home *** CD-ROM | disk | FTP | other *** search
/ Cream of the Crop 12 / Cream of the Crop 12 (Part II) / Cream of the Crop 12 (Part II).iso / OS2 / GNUSED.ZIP / sed / testsuite / LOG < prev    next >
Encoding:
Text File  |  1995-12-31  |  59.4 KB  |  1,867 lines
  1. Thu Dec 28
  2.  
  3. too slow on mac-mf;  run gprof
  4.  
  5. [15]    38.81   11.52     8.00 9498974+8346392 rx_rexp_equal [15]
  6. __
  7. added code to rx_rexp_equal to count n calls and result bias
  8. int re_abs = 0;
  9. int re_ans = 0;
  10.  
  11.   /**/
  12.   ++re_abs;
  13.   re_ans += (ret*2 - 1);
  14.  
  15. in gdb, br exit and check those
  16.  
  17.     Breakpoint 1, 0x1359a in exit ()
  18.     (gdb) p re_abs
  19.     $1 = 3416821
  20.     (gdb) p re_ans
  21.     $2 = -2793859
  22.  
  23. 82% likely to not be equal
  24. --
  25.  
  26. notice:
  27.  
  28. [16]    15.91    8.00     0.00 9847935      rx_bitset_is_equal [16]
  29.  
  30. the test in  rx_rexp_equal (a, b) is
  31.  
  32.   ret = (   (a->type == b->type)
  33.      && (a->params.cset_size == b->params.cset_size)
  34.      && (a->params.intval == b->params.intval)
  35.      && (a->params.intval2 == b->params.intval2)
  36.      && rx_bitset_is_equal (a->params.cset_size,
  37.                 a->params.cset,
  38.                 b->params.cset)
  39.      && rx_rexp_equal (a->params.pair.left, b->params.pair.left)
  40.      && rx_rexp_equal (a->params.pair.right, b->params.pair.right));
  41.  
  42.  
  43. and gprof confirms that rx_bitset_is_equal isn't being called from
  44. anyplace else.  
  45.  
  46. most calls are useless since most nodes prbly aren't event cset
  47. nodes.
  48.  
  49. re-order and prune...
  50.  
  51. before (-pg -g)
  52. 20.74user 0.31system 0:22.02elapsed 95%CPU (0avgtext+0avgdata 0maxresident)k
  53.  
  54. after
  55. 19.46user 0.15system 0:20.60elapsed 95%CPU (0avgtext+0avgdata 0maxresident)k
  56.  
  57.  
  58. gprof says:
  59.  
  60.  37.46     7.33     7.33          mcount
  61.  17.12     3.35    10.68   4021435  rx_rexp_equal
  62.   8.33     1.63    12.31   1114696  rx_bitset_is_equal
  63.  
  64. [13]    56.78    1.38     5.57 130048      rx_hash_store [13]
  65. [15]    40.69    3.35     1.63 2275803+1745632 rx_rexp_equal [15]
  66.  
  67. that seems awefully high for such short input ... perhaps rx_hash_store
  68. is being called too often.  These functions can get faster, but not
  69. an order of magnitude faster, which is what we're really after.
  70.  
  71. i think simplified regexps aren't cached reasonably.
  72.  
  73.  
  74. cache cached_rexp in rexp_node
  75.  
  76. 17.05user 0.06system 0:17.14elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
  77.  
  78. % time  seconds   cumsec   calls  function
  79.  35.05     5.98     5.98          mcount
  80.  15.89     2.71     8.69   3271085  rx_rexp_equal
  81.   7.74     1.32    10.01   919773  rx_bitset_is_equal
  82.  
  83.  
  84.  
  85. Thu Dec 28 15:28:26 PST 1995
  86.  
  87. -O3 comparison to /usr/bin/sed (GNU sed version 2.05) show about an
  88. O(10) slowdown.
  89.  
  90. -pg -g:
  91.  
  92. *** Start "time ./sed -f sep.sed < sep.inp > tmp" in ~/vac/rxdispencer/sed/testsuite/ at 15:30:08
  93. 0.66user 0.06system 0:00.81elapsed 88%CPU (0avgtext+0avgdata 0maxresident)k
  94.  
  95. % time  seconds   cumsec   calls  function
  96.  37.31     0.25     0.25          mcount
  97.  10.45     0.07     0.32   41465  rx_bitset_hash
  98.   7.46     0.05     0.37   43124  rx_rexp_equal
  99.   5.97     0.04     0.41    7003  rx_hash_store
  100.   4.48     0.03     0.44   33682  unfa_equal
  101.   4.48     0.03     0.47   12985  malloc
  102.   2.99     0.02     0.49    6899  rx_make_solutions
  103.   2.99     0.02     0.51    5727  rx_basic_make_solutions
  104.   1.49     0.01     0.52   89829  rx_rexp_hash
  105.   1.49     0.01     0.53    9491  nfa_set_enjoin
  106.   1.49     0.01     0.54    7791  hash_se_prog
  107.   1.49     0.01     0.55    7775  se_list_cmp
  108.   1.49     0.01     0.56    7760  rx_free_solutions
  109.   1.49     0.01     0.57    7204  rx_next_solution
  110.   1.49     0.01     0.58    6992  bzero
  111.   1.49     0.01     0.59    6899  canonical_unfa
  112.   1.49     0.01     0.60    6899  rx_free_unfa
  113.   1.49     0.01     0.61    6899  rx_start_superstate
  114.   1.49     0.01     0.62    6899  rx_terminate_system
  115.   1.49     0.01     0.63    6899  rx_unfa
  116.   1.49     0.01     0.64    6899  rx_unfa_rx
  117.   1.49     0.01     0.65    5727  init_basic_once
  118.   1.49     0.01     0.66      29  __sbrk
  119.   1.49     0.01     0.67      20  rx_superstate
  120.  
  121.  
  122. sep.sed:
  123. --------
  124.  
  125. # inspired by an autoconf generated configure script.
  126. s%/[^/][^/]*$%%
  127.  
  128.  
  129. sep.inp:
  130. --------
  131.  
  132. miss mary mack mack//mack/ran down/the track  track  track
  133. slashes\aren't%used enough/in/casual-conversation///
  134. possibly sentences would be more attractive if they ended in two slashes//
  135.  
  136.  
  137. Some call graph entries are revealing:
  138.  
  139. ----------------------------------------
  140.                  0.00     0.42  163/163      rx_regexec [5]
  141. [2]     99.97    0.00     0.42  163      rx_regmatch [2]
  142.                  0.02     0.30 5727/5727     rx_basic_make_solutions [9]
  143.                  0.01     0.07 5727/5727     rx_next_solution [15]
  144.                  0.00     0.02 5727/5727     rx_basic_free_solutions [23]
  145.  
  146. rx_regmatch is called 163 times -- almost once per character
  147. in the input.
  148.  
  149. It calls rx_basic_make_solutions 5727 times because for each starting
  150. position, it calls rx_basic_make_solutions for each possible length
  151. of match from longest to shortest until a match is found or all matches
  152. tried.
  153.  
  154. The fastmap optimization could save a lot here but would lose on a
  155. pattern starting with "." or "[a-zA-Z]".   In contrast, sed 2.05 doesn't
  156. slow down noticably when the command is changed to "s%./[^/][^/]*$%%".
  157.  
  158. rx_basic_make_solutions is called 5727 times
  159.  
  160. more from the call graph:
  161.  
  162.                  0.01     0.20 6899/6899     rx_unfa [10]
  163. [11]    49.68    0.01     0.20 6899      canonical_unfa [11]
  164.  
  165. there is a caching optimization in rx_unfa for the purpose of avoiding
  166. calls to canonical_unfa.   apparently it is buggy.  why?
  167.  
  168. it depends on the caching of simplified regexps....does that work?
  169. Here is a classic profiling trick, to find out:
  170.  
  171.     Program exited normally.
  172.     Breakpoint 1 at 0x109f1: file ../../rx/rxsimp.c, line 67.
  173.     Breakpoint 2 at 0x10a18: file ../../rx/rxsimp.c, line 72.
  174.     (gdb) comm 1
  175.     Type commands for when breakpoint 1 is hit, one per line.
  176.     End with a line saying just "end".
  177.     silent
  178.     cont
  179.     end
  180.     (gdb) comm 2
  181.     Type commands for when breakpoint 2 is hit, one per line.
  182.     End with a line saying just "end".
  183.     silent
  184.     cont
  185.     end
  186.     (gdb) run
  187.     [....]
  188.     (gdb) i br
  189.     1   breakpoint     keep y   0x000109f1 in rx_simple_rexp at ../../rx/rxsimp.c:67
  190.         breakpoint already hit 5802 times
  191.         silent
  192.         cont
  193.     2   breakpoint     keep y   0x00010a18 in rx_simple_rexp at ../../rx/rxsimp.c:72
  194.         breakpoint already hit 245 times
  195.         silent
  196.         cont
  197.  
  198. which means that caching is working just fine here (245:5802 miss ratio)
  199.  
  200. There's still a puzzle.
  201.  
  202. The expression in "s%/[a-z][a-z]*$%%" comes out to:
  203.  
  204.     (gdb) p print_rexp (256, 0, preg->pattern)
  205.     Node 3 type 1 (r_concat), iv=0( ), iv2=0, len=-1 obs=1 cs=nil
  206.       Node -1 type 0 (r_cset), iv=0( ), iv2=0, len=1 obs=0 cs=[/]
  207.       Node 2 type 1 (r_concat), iv=0( ), iv2=0, len=-1 obs=1 cs=nil
  208.         Node -1 type 0 (r_cset), iv=0( ), iv2=0, len=1 obs=0 cs=[abcdefghijklmnopqrstuvwxyz]
  209.         Node 1 type 1 (r_concat), iv=0( ), iv2=0, len=-1 obs=1 cs=nil
  210.           Node -1 type 4 (r_star), iv=0( ), iv2=0, len=-1 obs=0 cs=nil
  211.             Node -1 type 0 (r_cset), iv=0( ), iv2=0, len=1 obs=0 cs=[abcdefghijklmnopqrstuvwxyz]
  212.             nil
  213.           Node 0 type 8 (r_conext), iv=36($), iv2=0, len=0 obs=1 cs=nil
  214.     
  215. even 245 non-cached calls to rx_simple_rexp seems way out of hand.   Every node
  216. of the tree can be simplified and cached in at most:
  217.  
  218.         8    ; 1 call per node
  219.         6    ; 2 recursive calls per concat
  220.         1    ; 1 recursive call per star
  221.         --
  222.         15    ; 15 calls
  223.  
  224. probably fewer as some calls are likely counted twice.  So why 245?
  225.  
  226. pop to the main perf problem which was:
  227.  
  228.                      0.01     0.20 6899/6899     rx_unfa [10]
  229.     [11]    49.68    0.01     0.20 6899      canonical_unfa [11]
  230.  
  231.     there is a caching optimization in rx_unfa for the purpose of avoiding
  232.     calls to canonical_unfa.   apparently it is buggy.  why?
  233.  
  234.  
  235. What expressions is rx_unfa called for?
  236.  
  237.     $40 = (struct rexp_node *) 0x5adc0
  238.     $41 = (struct rexp_node *) 0x5adc0
  239.     $42 = (struct rexp_node *) 0x5adc0
  240.     $43 = (struct rexp_node *) 0x5adc0
  241.     [....]
  242.  
  243.  
  244. Poking around in gdb says that expression's unfa is cached properly
  245. but the cache is wrongly cleared here:
  246.  
  247.  
  248. =>      rx_basic_free_solutions (solutions);
  249.         if (answer == rx_yes)
  250.       ....
  251. in rxposix.c.
  252.  
  253. This is only a few "finish" and "next" steps away from where the cache
  254. is set.  So, it was found just by searching forward in the coarsest
  255. steps from a call to rx_unfa.  (Watchpoints crash gdb and sometimes linux
  256. under linux).
  257.  
  258. set a breakpoint there, ignored it 20 times, and confirmed that
  259. the cache is cleared.
  260.  
  261. Before:
  262.     (gdb) set $exp=solutions->exp
  263.  
  264.     (gdb) p $exp->simplified
  265.     $3519 = (struct rexp_node *) 0x5adc0
  266.     (gdb) p $exp->simplified->cr
  267.     $3520 = (struct rx_cached_rexp *) 0x57000
  268.     (gdb) p $exp->refs
  269.     $3521 = 2
  270.     (gdb) p $exp->simplified->refs
  271.     $3522 = 3
  272.  
  273. After:
  274.  
  275.     (gdb) p $exp->simplified
  276.     $3526 = (struct rexp_node *) 0x5adc0
  277.     (gdb) p $exp->simplified->cr
  278.     $3523 = (struct rx_cached_rexp *) 0x0
  279.     (gdb) p $exp->refs
  280.     $3525 = 1
  281.     (gdb) p $exp->simplified->refs
  282.     $3524 = 3
  283.  
  284. so next time, step into it.
  285.  
  286. ugh.... rx_free_unfa (unfa) was simply clearing the cache in
  287. what was obviously the wrong place (when the unfa refcount dropped
  288. to 0 instead of when it was actually flushed from the cache.)
  289. should have checked here a few steps ago, but writing the LOG
  290. was a distracting source of amusment.
  291.  
  292.  
  293. rebuild with fix
  294.  
  295. before:
  296.     *** Start "time ./sed -f sep.sed < sep.inp > tmp" in ~/vac/rxdispencer/sed/testsuite/ at 15:30:08
  297.     0.66user 0.06system 0:00.81elapsed 88%CPU (0avgtext+0avgdata 0maxresident)k
  298.  
  299.  
  300. after
  301.     *** Start "time ./sed -f sep.sed < sep.inp > tmp" in /home/lord/vac/rxdispencer/sed/testsuite/ at 16:34:52
  302.     0.35user 0.05system 0:00.45elapsed 88%CPU (0avgtext+0avgdata 0maxresident)k
  303.  
  304.  
  305. 2 or 3 more of those, and we're totally in business.
  306.  
  307.  
  308.  
  309.  
  310. Thu Dec 28 15:28:26 PST 1995
  311.  
  312.     *** Start "time ./sed -f sep.sed < sep.inp > tmp" in /home/lord/vac/rxdispencer/sed/testsuite/ at 16:34:52
  313.     0.35user 0.05system 0:00.45elapsed 88%CPU (0avgtext+0avgdata 0maxresident)k
  314.  
  315. profile has changed considerably.  good!
  316.  
  317.     % time  seconds   cumsec   calls  function
  318.      38.89     0.14     0.14          mcount
  319.      16.67     0.06     0.20   12985  malloc
  320.      11.11     0.04     0.24    8085  eclose_node
  321.       8.33     0.03     0.27    6137  rx_soluntion_fit_p
  322.       5.56     0.02     0.29   12637  free
  323.       2.78     0.01     0.30    7760  rx_free_solutions
  324.       2.78     0.01     0.31    6899  rx_make_solutions
  325.       2.78     0.01     0.32    6899  rx_terminate_system
  326.       2.78     0.01     0.33    6899  rx_unfa
  327.       2.78     0.01     0.34    6137  rx_fit_p
  328.       2.78     0.01     0.35     163  rx_regmatch
  329.       2.78     0.01     0.36      20  rx_superstate
  330.     
  331. eclose_node?!?!?!
  332.  
  333. but more pressing is that some tests now segfault.
  334.  
  335. ...
  336.  
  337. -O3 causes the segfaults.  hopefully this is a compiler bug.  i think
  338. i've seen this on linux before.
  339.  
  340. -O has no problem.
  341.  
  342.  
  343.  
  344.  
  345. Stepping back a bit...here is the state of some timing tests.
  346.  
  347. This is -O vs. the mysterious sed 2.05 in /usr/bin.
  348.  
  349.  
  350.     time ./sed -f enable.sed < enable.inp > tmp
  351.     0.02user 0.03system 0:00.16elapsed 31%CPU (0avgtext+0avgdata 0maxresident)k
  352.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  353.     cmp enable.good tmp
  354.  
  355.     time /usr/bin/sed -f enable.sed < enable.inp > tmp2
  356.     0.00user 0.01system 0:00.10elapsed 10%CPU (0avgtext+0avgdata 0maxresident)k
  357.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  358.     cmp enable.good tmp2
  359.  
  360.  
  361.  
  362.  
  363.     time ./sed -f sep.sed < sep.inp > tmp
  364.     0.13user 0.02system 0:00.16elapsed 93%CPU (0avgtext+0avgdata 0maxresident)k
  365.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  366.     cmp sep.good tmp
  367.  
  368.     time /usr/bin/sed -f sep.sed < sep.inp > tmp2
  369.     0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  370.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  371.     cmp sep.good tmp2
  372.  
  373.  
  374.  
  375.  
  376.     time ./sed -f inclib.sed < inclib.inp > tmp
  377.     0.10user 0.01system 0:00.12elapsed 91%CPU (0avgtext+0avgdata 0maxresident)k
  378.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  379.     cmp inclib.good tmp
  380.  
  381.     time /usr/bin/sed -f inclib.sed < inclib.inp > tmp2
  382.     0.00user 0.02system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  383.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  384.     cmp inclib.good tmp2
  385.  
  386.  
  387.  
  388.  
  389.     time ./sed -f 8bit.sed < 8bit.inp > tmp
  390.     0.03user 0.02system 0:00.05elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  391.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  392.     cmp 8bit.good tmp
  393.  
  394.     time /usr/bin/sed -f 8bit.sed < 8bit.inp > tmp2
  395.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  396.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  397.     cmp 8bit.good tmp2
  398.  
  399.  
  400.  
  401.  
  402.     time ./sed -f newjis.sed < newjis.inp > tmp
  403.     0.03user 0.01system 0:00.09elapsed 44%CPU (0avgtext+0avgdata 0maxresident)k
  404.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  405.     cmp newjis.good tmp
  406.  
  407.     time /usr/bin/sed -f newjis.sed < newjis.inp > tmp2
  408.     0.00user 0.03system 0:00.06elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  409.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  410.     cmp newjis.good tmp2
  411.  
  412.  
  413.  
  414.  
  415.     time ./sed -n -f cv-vars.sed < cv-vars.inp > tmp
  416.     0.02user 0.05system 0:00.08elapsed 87%CPU (0avgtext+0avgdata 0maxresident)k
  417.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  418.     cmp cv-vars.good tmp
  419.  
  420.     time /usr/bin/sed -n -f cv-vars.sed < cv-vars.inp > tmp2
  421.     0.01user 0.02system 0:00.04elapsed 75%CPU (0avgtext+0avgdata 0maxresident)k
  422.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  423.     cmp cv-vars.good tmp2
  424.  
  425.  
  426.  
  427.  
  428.     time ./sed -f manis.sed < manis.inp > tmp
  429.     0.44user 0.03system 0:00.48elapsed 97%CPU (0avgtext+0avgdata 0maxresident)k
  430.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  431.     cmp manis.inp tmp
  432.  
  433.     time /usr/bin/sed -f manis.sed < manis.inp > tmp2
  434.     0.02user 0.02system 0:00.04elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  435.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  436.     cmp manis.inp tmp2
  437.  
  438.  
  439.  
  440.  
  441.     time ./sed -f xabcx.sed < xabcx.inp > tmp
  442.     0.00user 0.04system 0:00.04elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  443.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  444.     cmp xabcx.good tmp
  445.  
  446.     time /usr/bin/sed -f xabcx.sed < xabcx.inp > tmp2
  447.     0.01user 0.02system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  448.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  449.     cmp xabcx.good tmp2
  450.  
  451.  
  452.  
  453.  
  454.     time ./sed -f dollar.sed < dollar.inp > tmp
  455.     0.00user 0.03system 0:00.05elapsed 60%CPU (0avgtext+0avgdata 0maxresident)k
  456.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  457.     cmp dollar.good tmp
  458.  
  459.     time /usr/bin/sed -f dollar.sed < dollar.inp > tmp2
  460.     0.01user 0.01system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  461.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  462.     cmp dollar.good tmp2
  463.  
  464.  
  465.  
  466.  
  467.     time ./sed -f noeol.sed < noeol.inp > tmp
  468.     0.01user 0.03system 0:00.04elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  469.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  470.     cmp noeol.good tmp
  471.  
  472.     time /usr/bin/sed -f noeol.sed < noeol.inp > tmp2
  473.     0.00user 0.02system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  474.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  475.     cmp noeol.good tmp2
  476.  
  477.  
  478.  
  479.  
  480.     time ./sed -f sub-num.sed < sub-num.inp > tmp
  481.     0.01user 0.03system 0:00.05elapsed 80%CPU (0avgtext+0avgdata 0maxresident)k
  482.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  483.     cmp sub-num.good tmp
  484.  
  485.     time /usr/bin/sed -f sub-num.sed < sub-num.inp > tmp2
  486.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  487.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  488.     cmp sub-num.good tmp2
  489.  
  490.  
  491.  
  492.  
  493.     time ./sed -f sub-all.sed < sub-num.inp > tmp
  494.     0.02user 0.02system 0:00.04elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  495.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  496.     cmp sub-all.good tmp
  497.  
  498.     time /usr/bin/sed -f sub-all.sed < sub-num.inp > tmp2
  499.     0.01user 0.02system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  500.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  501.     cmp sub-all.good tmp2
  502.  
  503.  
  504.  
  505.  
  506.     time ./sed -f subwrite.sed < subwrite.inp > tmp1
  507.     0.03user 0.02system 0:00.05elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  508.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  509.     cmp subwrite.good1 tmp1
  510.     cmp subwrite.good2 tmp2
  511.  
  512.     time /usr/bin/sed -f subwrite.sed < subwrite.inp > tmp1
  513.     0.01user 0.01system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  514.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  515.     cmp subwrite.good1 tmp1
  516.     cmp subwrite.good2 tmp2
  517.  
  518.  
  519.  
  520.  
  521.     time ./sed -f head.sed < head.inp > tmp
  522.     0.01user 0.00system 0:00.01elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  523.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  524.     cmp head.good tmp
  525.  
  526.     time /usr/bin/sed -f head.sed < head.inp > tmp2
  527.     0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  528.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  529.     cmp head.good tmp2
  530.  
  531.  
  532.  
  533.     time ./sed -n -f middle.sed < head.inp > tmp
  534.     0.01user 0.00system 0:00.02elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  535.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  536.     cmp middle.good tmp
  537.  
  538.     time /usr/bin/sed -n -f middle.sed < head.inp > tmp2
  539.     0.00user 0.01system 0:00.02elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  540.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  541.     cmp middle.good tmp2
  542.  
  543.  
  544.  
  545.  
  546.     time ./sed --file=newjis.sed < newjis.inp > tmp
  547.     0.02user 0.01system 0:00.04elapsed 75%CPU (0avgtext+0avgdata 0maxresident)k
  548.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  549.     cmp newjis.good tmp
  550.  
  551.     time /usr/bin/sed --file=newjis.sed < newjis.inp > tmp2
  552.     0.01user 0.01system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  553.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  554.     cmp newjis.good tmp2
  555.  
  556.  
  557.  
  558.     time ./sed --quiet -f cv-vars.sed < cv-vars.inp > tmp
  559.     0.01user 0.04system 0:00.07elapsed 71%CPU (0avgtext+0avgdata 0maxresident)k
  560.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  561.     cmp cv-vars.good tmp
  562.  
  563.     time /usr/bin/sed --quiet -f cv-vars.sed < cv-vars.inp > tmp2
  564.     0.01user 0.02system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  565.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  566.     cmp cv-vars.good tmp2
  567.  
  568.  
  569.  
  570.  
  571.  
  572.  
  573. So far, most often ./sed loses (not always).   But we're still winning:
  574.  
  575.  
  576.     time ./sed -f maddingcrowd.sed < maddingcrowd.inp > tmp
  577.     2.17user 0.22system 0:02.40elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
  578.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  579.     cmp tmp maddingcrowd.good
  580.  
  581.     # DO NOT time /usr/bin/sed -f maddingcrowd.sed < maddingcrowd.inp > tmp2
  582.     # sed 2.05....  t->+inf
  583.  
  584.  
  585.  
  586. but also still losing:
  587.  
  588.     time /usr/bin/sed -f mac-mf.sed < mac-mf.inp > tmp" in ~/vac/rxdispencer/sed/testsuite/ at 17:19:08
  589.     0.29user 0.09system 0:00.39elapsed 97%CPU (0avgtext+0avgdata 0maxresident)k
  590.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  591.  
  592.  
  593.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp" in ~/vac/rxdispencer/sed/testsuite/ at 17:19:08
  594.     t->inf
  595.  
  596.  
  597.  
  598.  
  599.  
  600. Fri Dec 29 12:03:28 PST 1995
  601.  
  602.  
  603. ran mac-mf.sed on small input for profiling.
  604.  
  605.      32.17     1.66     1.66          mcount
  606.      10.27     0.53     2.19   262506  malloc
  607.       6.98     0.36     2.55   260030  free
  608.       6.20     0.32     2.87   129914  rx_make_solutions
  609.       6.01     0.31     3.18   129914  rx_start_superstate
  610.       5.43     0.28     3.46   129978  eclose_node
  611.       3.68     0.19     3.65   129972  hash_se_prog
  612.       3.49     0.18     3.83    4205  rx_regmatch
  613.       3.10     0.16     3.99   129916  rx_next_solution
  614.       3.10     0.16     4.15   129914  rx_unfa
  615.       2.52     0.13     4.28   129728  rx_basic_make_solutions
  616.       2.33     0.12     4.40   129914  rx_free_unfa
  617.       1.94     0.10     4.50   132334  bzero
  618.       1.74     0.09     4.59   161119  rx_free_rexp
  619.       1.36     0.07     4.66   161229  rx_save_rexp
  620.       1.16     0.06     4.72   130096  rx_free_solutions
  621.       1.16     0.06     4.78   129992  nfa_set_enjoin
  622.       1.16     0.06     4.84   129914  rx_terminate_system
  623.       0.97     0.05     4.89   129958  rx_state_possible_futures
  624.       0.97     0.05     4.94   129728  rx_basic_free_solutions
  625.       0.78     0.04     4.98   129914  rx_unfa_rx
  626.       0.58     0.03     5.01   129914  rx_init_system
  627.       0.58     0.03     5.04   129914  se_list_cmp
  628.       0.58     0.03     5.07   31241  rx_simple_rexp
  629.       0.39     0.02     5.09     698  inverse_translation
  630.       0.19     0.01     5.10   23082  rx_fit_p
  631.       0.19     0.01     5.11    4820  inchar
  632.       0.19     0.01     5.12     364  rx_hash_store
  633.       0.19     0.01     5.13     125  rx_bitset_difference
  634.       0.19     0.01     5.14      94  __sbrk
  635.       0.19     0.01     5.15       1  __isatty
  636.       0.19     0.01     5.16       1  compile_program
  637.     
  638. malloc is top, called many many times -- approx. half the calls to
  639. that must be from rx_make_solutions.  
  640.  
  641. Most of those are from rx_basic_make_solutions.
  642.  
  643. All of those are from rx_regmatch, which is called far fewer times
  644. (approx 1:31).
  645.  
  646. All of those (in this case) are from rx_regexec, called only 
  647. 138 times. 
  648.  
  649.  
  650. fastmapping can prune many calls from regexec to regmatch so add
  651. the fastmapping optimization copying/fixing code from an older rx.
  652.  
  653. before fastmapping:
  654.     time ./sed -f mac-mf.sed < ,a
  655.     5.14user 0.14system 0:08.13elapsed 64%CPU (0avgtext+0avgdata 0maxresident)k
  656.  
  657. after fastmapping:
  658.     ./sed -f mac-mf.sed < ,a
  659.     0.85user 0.09system 0:01.08elapsed 87%CPU (0avgtext+0avgdata 0maxresident)k
  660.  
  661.  
  662.  
  663. rerun -O timing/bug tests
  664.  
  665. some bug in the spencer test....
  666.  
  667.     time ./sed -f enable.sed < enable.inp > tmp
  668.     0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  669.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  670.     cmp enable.good tmp
  671.  
  672.     time /usr/bin/sed -f enable.sed < enable.inp > tmp2
  673.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  674.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  675.     cmp enable.good tmp2
  676.  
  677.  
  678.  
  679.  
  680.     time ./sed -f sep.sed < sep.inp > tmp
  681.     0.02user 0.03system 0:00.05elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  682.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  683.     cmp sep.good tmp
  684.  
  685.     time /usr/bin/sed -f sep.sed < sep.inp > tmp2
  686.     0.01user 0.02system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  687.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  688.     cmp sep.good tmp2
  689.  
  690.  
  691.  
  692.  
  693.     time ./sed -f inclib.sed < inclib.inp > tmp
  694.     0.03user 0.00system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  695.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  696.     cmp inclib.good tmp
  697.  
  698.     time /usr/bin/sed -f inclib.sed < inclib.inp > tmp2
  699.     0.01user 0.02system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  700.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  701.     cmp inclib.good tmp2
  702.  
  703.  
  704.  
  705.  
  706.     time ./sed -f 8bit.sed < 8bit.inp > tmp
  707.     0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  708.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  709.     cmp 8bit.good tmp
  710.  
  711.     time /usr/bin/sed -f 8bit.sed < 8bit.inp > tmp2
  712.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  713.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  714.     cmp 8bit.good tmp2
  715.  
  716.  
  717.  
  718.  
  719.     time ./sed -f newjis.sed < newjis.inp > tmp
  720.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  721.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  722.     cmp newjis.good tmp
  723.  
  724.     time /usr/bin/sed -f newjis.sed < newjis.inp > tmp2
  725.     0.00user 0.02system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  726.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  727.     cmp newjis.good tmp2
  728.  
  729.  
  730.  
  731.  
  732.     time ./sed -n -f cv-vars.sed < cv-vars.inp > tmp
  733.     0.01user 0.05system 0:00.06elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  734.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  735.     cmp cv-vars.good tmp
  736.  
  737.     time /usr/bin/sed -n -f cv-vars.sed < cv-vars.inp > tmp2
  738.     0.01user 0.02system 0:00.04elapsed 75%CPU (0avgtext+0avgdata 0maxresident)k
  739.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  740.     cmp cv-vars.good tmp2
  741.  
  742.  
  743.  
  744.  
  745.     time ./sed -f manis.sed < manis.inp > tmp
  746.     0.10user 0.03system 0:00.13elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  747.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  748.     cmp manis.inp tmp
  749.  
  750.     time /usr/bin/sed -f manis.sed < manis.inp > tmp2
  751.     0.01user 0.03system 0:00.04elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  752.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  753.     cmp manis.inp tmp2
  754.  
  755.  
  756.  
  757.  
  758.     time ./sed -f xabcx.sed < xabcx.inp > tmp
  759.     0.01user 0.02system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  760.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  761.     cmp xabcx.good tmp
  762.  
  763.     time /usr/bin/sed -f xabcx.sed < xabcx.inp > tmp2
  764.     0.01user 0.01system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  765.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  766.     cmp xabcx.good tmp2
  767.  
  768.  
  769.  
  770.  
  771.     time ./sed -f dollar.sed < dollar.inp > tmp
  772.     0.01user 0.01system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  773.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  774.     cmp dollar.good tmp
  775.  
  776.     time /usr/bin/sed -f dollar.sed < dollar.inp > tmp2
  777.     0.00user 0.02system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  778.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  779.     cmp dollar.good tmp2
  780.  
  781.  
  782.  
  783.  
  784.     time ./sed -f noeol.sed < noeol.inp > tmp
  785.     0.01user 0.02system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  786.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  787.     cmp noeol.good tmp
  788.  
  789.     time /usr/bin/sed -f noeol.sed < noeol.inp > tmp2
  790.     0.01user 0.01system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  791.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  792.     cmp noeol.good tmp2
  793.  
  794.  
  795.  
  796.  
  797.     time ./sed -f sub-num.sed < sub-num.inp > tmp
  798.     0.01user 0.01system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  799.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  800.     cmp sub-num.good tmp
  801.  
  802.     time /usr/bin/sed -f sub-num.sed < sub-num.inp > tmp2
  803.     0.01user 0.01system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  804.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  805.     cmp sub-num.good tmp2
  806.  
  807.  
  808.  
  809.  
  810.     time ./sed -f sub-all.sed < sub-num.inp > tmp
  811.     0.01user 0.02system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  812.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  813.     cmp sub-all.good tmp
  814.  
  815.     time /usr/bin/sed -f sub-all.sed < sub-num.inp > tmp2
  816.     0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  817.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  818.     cmp sub-all.good tmp2
  819.  
  820.  
  821.  
  822.  
  823.     time ./sed -f subwrite.sed < subwrite.inp > tmp1
  824.     0.02user 0.00system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  825.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  826.     cmp subwrite.good1 tmp1
  827.     cmp subwrite.good2 tmp2
  828.  
  829.     time /usr/bin/sed -f subwrite.sed < subwrite.inp > tmp1
  830.     0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  831.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  832.     cmp subwrite.good1 tmp1
  833.     cmp subwrite.good2 tmp2
  834.  
  835.  
  836.  
  837.  
  838.     time ./sed -f head.sed < head.inp > tmp
  839.     0.01user 0.01system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  840.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  841.     cmp head.good tmp
  842.  
  843.     time /usr/bin/sed -f head.sed < head.inp > tmp2
  844.     0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  845.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  846.     cmp head.good tmp2
  847.  
  848.  
  849.  
  850.  
  851.     time ./sed -n -f middle.sed < head.inp > tmp
  852.     0.00user 0.01system 0:00.01elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  853.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  854.     cmp middle.good tmp
  855.  
  856.     time /usr/bin/sed -n -f middle.sed < head.inp > tmp2
  857.     0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  858.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  859.     cmp middle.good tmp2
  860.  
  861.  
  862.  
  863.  
  864.     time ./sed -f maddingcrowd.sed < maddingcrowd.inp > tmp
  865.     2.13user 0.26system 0:02.76elapsed 86%CPU (0avgtext+0avgdata 0maxresident)k
  866.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  867.     cmp tmp maddingcrowd.good
  868.  
  869.     time /usr/bin/sed -f maddingcrowd.sed < maddingcrowd.inp > tmp2
  870.     t->inf
  871.  
  872.  
  873.  
  874.  
  875.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  876.     21.74user 0.16system 0:21.90elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  877.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  878.     cmp tmp mac-mf.good
  879.  
  880.     time /usr/bin/sed -f mac-mf.sed < mac-mf.inp > tmp2
  881.     0.28user 0.11system 0:00.39elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  882.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  883.     cmp tmp2 mac-mf.good
  884.  
  885.  
  886.  
  887.  
  888.     time ./sed -f khadafy.sed < khadafy.inp > tmp
  889.     0.02user 0.01system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  890.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  891.     cmp tmp khadafy.inp
  892.  
  893.     time /usr/bin/sed -f khadafy.sed < khadafy.inp > tmp2
  894.     0.01user 0.03system 0:00.04elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  895.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  896.     cmp tmp2 khadafy.inp
  897.     
  898.     
  899.  
  900.     time ./sed -f linecnt.sed < linecnt.inp > tmp
  901.     0.00user 0.01system 0:00.01elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  902.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  903.     cmp tmp linecnt.good
  904.  
  905.     time /usr/bin/sed -f linecnt.sed < linecnt.inp > tmp2
  906.     0.01user 0.01system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  907.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  908.     cmp tmp2 linecnt.good
  909.  
  910.  
  911.  
  912. Generally close.  One very winning case (maddingcrowd).   One pretty much
  913. losing case (but not as bad as before) mac-mf.
  914.  
  915.  
  916. All tests pass except spencer.
  917.  
  918. All tests reasonable performance except "distrib" and "mac-mf".
  919.  
  920.  
  921. Spencer:
  922.     was typo in test suite but that fixed, still bugs:
  923.  
  924.         Test #37 failed!
  925.         Test #62 failed!
  926.  
  927.  
  928. #37 -- test suite was wrong -- sed, right -- pattern bogus.
  929.     lines 2945-2947 of 2003.2-1992
  930.  
  931. #62 -- test suite wrong again -- sed, right -- pattern not bogus
  932.     lines 3058-3060 and 3066-3077 of 2003.2-1992
  933.  
  934. spencer test passes with those fixes.
  935.  
  936.  
  937.  
  938. Fri Dec 29 13:14:02 PST 1995
  939.  
  940.  
  941. last development before release issues:
  942.  
  943.     All tests reasonable performance except "distrib" and "mac-mf".
  944.  
  945.  
  946.  
  947.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  948.     22.10user 0.22system 0:22.52elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
  949.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  950.     cmp tmp mac-mf.good
  951.  
  952.     time /usr/bin/sed -f mac-mf.sed < mac-mf.inp > tmp2
  953.     0.31user 0.09system 0:00.40elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  954.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  955.     cmp tmp2 mac-mf.good
  956.  
  957.     % time  seconds   cumsec   calls  function
  958.      34.18    19.43    19.43          mcount
  959.       6.03     3.43    22.86   2545726  free
  960.       5.96     3.39    26.25   2561762  malloc
  961.       5.44     3.09    29.34   1324635  eclose_node
  962.       3.83     2.18    31.52   41025  rx_regmatch
  963.       3.61     2.05    33.57   1276850  rx_next_solution
  964.       3.36     1.91    35.48   1276625  rx_start_superstate
  965.       3.22     1.83    37.31   1276625  rx_make_solutions
  966.       3.17     1.80    39.11   1276625  rx_free_unfa
  967.       2.94     1.67    40.78   1217560  rx_fit_p
  968.       2.41     1.37    42.15   1265155  rx_basic_make_solutions
  969.       2.27     1.29    43.44   1276625  rx_unfa
  970.       2.20     1.25    44.69   1223796  rx_simple_rexp
  971.       2.13     1.21    45.90   1280457  bzero
  972.       2.01     1.14    47.04   1287172  rx_free_solutions
  973.       1.55     0.88    47.92   1217560  rx_soluntion_fit_p
  974.       1.51     0.86    48.78   1278517  rx_state_possible_futures
  975.       1.44     0.82    49.60   1312946  hash_se_prog
  976.       1.41     0.80    50.40   1276625  rx_unfa_rx
  977.       1.39     0.79    51.19   1217560  rx_str_vmfn
  978.       1.18     0.67    51.86   2500305  rx_free_rexp
  979.       1.13     0.64    52.50   2500621  rx_save_rexp
  980.       1.11     0.63    53.13   1381011  nfa_set_enjoin
  981.       0.83     0.47    53.60   1312343  se_list_cmp
  982.       0.83     0.47    54.07   12948  rx_hash_store
  983.       0.77     0.44    54.51   1265155  init_basic_once
  984.     
  985.  
  986. which means, really, that no function dominates and again, avoiding
  987. the many many calls to rx_regmatch is key.
  988.  
  989. looking at the script, there are many anchored patterns and i recall
  990. an old rx optimization "don't waste time trying an anchored match
  991. in the middle of a pattern."  Let's put that back in.
  992.  
  993.  
  994. -pg before is_anchored
  995.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  996.     22.10user 0.22system 0:22.52elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
  997.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  998.     cmp tmp mac-mf.good
  999.  
  1000.  
  1001. -pg after
  1002.  
  1003.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  1004.     8.22user 0.31system 0:15.97elapsed 53%CPU (0avgtext+0avgdata 0maxresident)k
  1005.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1006.     cmp tmp mac-mf.good
  1007.  
  1008.  
  1009. also:
  1010.  
  1011.       2.60     0.22     5.76   141219  rx_make_solutions
  1012.  
  1013. meaning that we cut down about O(10) on calls to rx_make_solutions.
  1014.  
  1015.     *** Start "make" in /home/lord/vac/rxdispencer/sed/testsuite/ at 13:49:53
  1016.     time ./sed -f enable.sed < enable.inp > tmp
  1017.     0.01user 0.04system 0:01.75elapsed 2%CPU (0avgtext+0avgdata 0maxresident)k
  1018.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1019.     cmp enable.good tmp
  1020.     time /usr/bin/sed -f enable.sed < enable.inp > tmp2
  1021.     0.01user 0.03system 0:00.12elapsed 33%CPU (0avgtext+0avgdata 0maxresident)k
  1022.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1023.     cmp enable.good tmp2
  1024.     time ./sed -f sep.sed < sep.inp > tmp
  1025.     0.02user 0.01system 0:00.25elapsed 12%CPU (0avgtext+0avgdata 0maxresident)k
  1026.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1027.     cmp sep.good tmp
  1028.     time /usr/bin/sed -f sep.sed < sep.inp > tmp2
  1029.     0.00user 0.04system 0:00.16elapsed 25%CPU (0avgtext+0avgdata 0maxresident)k
  1030.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1031.     cmp sep.good tmp2
  1032.     time ./sed -f inclib.sed < inclib.inp > tmp
  1033.     0.02user 0.01system 0:00.05elapsed 60%CPU (0avgtext+0avgdata 0maxresident)k
  1034.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1035.     cmp inclib.good tmp
  1036.     time /usr/bin/sed -f inclib.sed < inclib.inp > tmp2
  1037.     0.00user 0.02system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  1038.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1039.     cmp inclib.good tmp2
  1040.     time ./sed -f 8bit.sed < 8bit.inp > tmp
  1041.     0.00user 0.01system 0:00.03elapsed 33%CPU (0avgtext+0avgdata 0maxresident)k
  1042.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1043.     cmp 8bit.good tmp
  1044.     time /usr/bin/sed -f 8bit.sed < 8bit.inp > tmp2
  1045.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1046.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1047.     cmp 8bit.good tmp2
  1048.     time ./sed -f newjis.sed < newjis.inp > tmp
  1049.     0.01user 0.01system 0:00.04elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1050.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1051.     cmp newjis.good tmp
  1052.     time /usr/bin/sed -f newjis.sed < newjis.inp > tmp2
  1053.     0.00user 0.04system 0:00.10elapsed 40%CPU (0avgtext+0avgdata 0maxresident)k
  1054.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1055.     cmp newjis.good tmp2
  1056.     time ./sed -n -f cv-vars.sed < cv-vars.inp > tmp
  1057.     0.02user 0.03system 0:00.40elapsed 12%CPU (0avgtext+0avgdata 0maxresident)k
  1058.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1059.     cmp cv-vars.good tmp
  1060.     time /usr/bin/sed -n -f cv-vars.sed < cv-vars.inp > tmp2
  1061.     0.00user 0.04system 0:00.04elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1062.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1063.     cmp cv-vars.good tmp2
  1064.     time ./sed -f manis.sed < manis.inp > tmp
  1065.     0.07user 0.04system 0:00.16elapsed 68%CPU (0avgtext+0avgdata 0maxresident)k
  1066.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1067.     cmp manis.inp tmp
  1068.     time /usr/bin/sed -f manis.sed < manis.inp > tmp2
  1069.     0.00user 0.04system 0:00.16elapsed 25%CPU (0avgtext+0avgdata 0maxresident)k
  1070.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1071.     cmp manis.inp tmp2
  1072.     time ./sed -f xabcx.sed < xabcx.inp > tmp
  1073.     0.00user 0.02system 0:00.05elapsed 40%CPU (0avgtext+0avgdata 0maxresident)k
  1074.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1075.     cmp xabcx.good tmp
  1076.     time /usr/bin/sed -f xabcx.sed < xabcx.inp > tmp2
  1077.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1078.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1079.     cmp xabcx.good tmp2
  1080.     time ./sed -f dollar.sed < dollar.inp > tmp
  1081.     0.00user 0.02system 0:00.04elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1082.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1083.     cmp dollar.good tmp
  1084.     time /usr/bin/sed -f dollar.sed < dollar.inp > tmp2
  1085.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1086.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1087.     cmp dollar.good tmp2
  1088.     time ./sed -f noeol.sed < noeol.inp > tmp
  1089.     0.03user 0.00system 0:00.05elapsed 60%CPU (0avgtext+0avgdata 0maxresident)k
  1090.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1091.     cmp noeol.good tmp
  1092.     time /usr/bin/sed -f noeol.sed < noeol.inp > tmp2
  1093.     0.01user 0.01system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1094.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1095.     cmp noeol.good tmp2
  1096.     time ./sed -f sub-num.sed < sub-num.inp > tmp
  1097.     0.01user 0.01system 0:00.04elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1098.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1099.     cmp sub-num.good tmp
  1100.     time /usr/bin/sed -f sub-num.sed < sub-num.inp > tmp2
  1101.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1102.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1103.     cmp sub-num.good tmp2
  1104.     time ./sed -f sub-all.sed < sub-num.inp > tmp
  1105.     0.01user 0.02system 0:00.08elapsed 37%CPU (0avgtext+0avgdata 0maxresident)k
  1106.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1107.     cmp sub-all.good tmp
  1108.     time /usr/bin/sed -f sub-all.sed < sub-num.inp > tmp2
  1109.     0.00user 0.02system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  1110.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1111.     cmp sub-all.good tmp2
  1112.     time ./sed -f subwrite.sed < subwrite.inp > tmp1
  1113.     0.01user 0.01system 0:00.04elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1114.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1115.     cmp subwrite.good1 tmp1
  1116.     cmp subwrite.good2 tmp2
  1117.     time /usr/bin/sed -f subwrite.sed < subwrite.inp > tmp1
  1118.     0.01user 0.01system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  1119.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1120.     cmp subwrite.good1 tmp1
  1121.     cmp subwrite.good2 tmp2
  1122.     time ./sed -f head.sed < head.inp > tmp
  1123.     0.00user 0.02system 0:00.04elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1124.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1125.     cmp head.good tmp
  1126.     time /usr/bin/sed -f head.sed < head.inp > tmp2
  1127.     0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1128.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1129.     cmp head.good tmp2
  1130.     time ./sed -n -f middle.sed < head.inp > tmp
  1131.     0.00user 0.01system 0:00.01elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1132.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1133.     cmp middle.good tmp
  1134.     time /usr/bin/sed -n -f middle.sed < head.inp > tmp2
  1135.     0.00user 0.01system 0:00.02elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1136.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1137.     cmp middle.good tmp2
  1138.     time ./sed -f maddingcrowd.sed < maddingcrowd.inp > tmp
  1139.     2.18user 0.36system 0:10.25elapsed 24%CPU (0avgtext+0avgdata 0maxresident)k
  1140.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1141.     cmp tmp maddingcrowd.good
  1142.     echo DO NOT time /usr/bin/sed -f maddingcrowd.sed < maddingcrowd.inp > tmp2
  1143.     echo sed 2.05....  t->+inf
  1144.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  1145.     2.52user 0.14system 0:02.92elapsed 91%CPU (0avgtext+0avgdata 0maxresident)k
  1146.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1147.     cmp tmp mac-mf.good
  1148.     time /usr/bin/sed -f mac-mf.sed < mac-mf.inp > tmp2
  1149.     0.26user 0.14system 0:00.44elapsed 90%CPU (0avgtext+0avgdata 0maxresident)k
  1150.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1151.     cmp tmp2 mac-mf.good
  1152.     time ./sed -f khadafy.sed < khadafy.inp > tmp
  1153.     0.02user 0.00system 0:00.06elapsed 33%CPU (0avgtext+0avgdata 0maxresident)k
  1154.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1155.     cmp tmp khadafy.inp
  1156.     time /usr/bin/sed -f khadafy.sed < khadafy.inp > tmp2
  1157.     0.01user 0.03system 0:00.04elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1158.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1159.     cmp tmp2 khadafy.inp
  1160.     sh spencer.sh ./sed <  spencer.inp > spencer.tmp 
  1161.     sh spencer.tmp
  1162.     time ./sed -f linecnt.sed < linecnt.inp > tmp
  1163.     0.00user 0.01system 0:00.05elapsed 20%CPU (0avgtext+0avgdata 0maxresident)k
  1164.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1165.     cmp tmp linecnt.good
  1166.     time /usr/bin/sed -f linecnt.sed < linecnt.inp > tmp2
  1167.     0.00user 0.01system 0:00.02elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1168.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1169.     cmp tmp2 linecnt.good
  1170.     sh distrib.sh ./sed < distrib.inp > tmp
  1171.     cmp tmp distrib.good
  1172.     time ./sed -f writeout.sed < writeout.inp >tmp1
  1173.     0.01user 0.03system 0:00.05elapsed 80%CPU (0avgtext+0avgdata 0maxresident)k
  1174.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1175.     cmp tmp1 writeout.good1
  1176.     cmp tmp2 writeout.good2
  1177.     time ./sed -f readin.sed < readin.inp >tmp
  1178.     0.01user 0.02system 0:00.05elapsed 60%CPU (0avgtext+0avgdata 0maxresident)k
  1179.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1180.     cmp tmp readin.good
  1181.     time /usr/bin/sed -f readin.sed < readin.inp >tmp2
  1182.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1183.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1184.     cmp tmp2 readin.good
  1185.     ./sed --help > tmp1
  1186.     ./sed -h > tmp2
  1187.     ./sed > tmp3 2>&1
  1188.     make: [help] Error 4 (ignored)
  1189.     cmp tmp1 tmp2
  1190.     cmp tmp2 tmp3
  1191.     cmp tmp1 help.good
  1192.     tmp1 help.good differ: char 9, line 1
  1193.     make: [help] Error 1 (ignored)
  1194.     ./sed --version  > tmp1 2>&1
  1195.     ./sed -V > tmp2 2>&1
  1196.     cmp tmp1 tmp2
  1197.     cmp tmp1 version.good
  1198.     time ./sed --file=newjis.sed < newjis.inp > tmp
  1199.     0.01user 0.01system 0:00.04elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1200.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1201.     cmp newjis.good tmp
  1202.     time /usr/bin/sed --file=newjis.sed < newjis.inp > tmp2
  1203.     0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1204.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1205.     cmp newjis.good tmp2
  1206.     time ./sed --quiet -f cv-vars.sed < cv-vars.inp > tmp
  1207.     0.03user 0.03system 0:00.06elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1208.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1209.     cmp cv-vars.good tmp
  1210.     time /usr/bin/sed --quiet -f cv-vars.sed < cv-vars.inp > tmp2
  1211.     0.01user 0.02system 0:00.04elapsed 75%CPU (0avgtext+0avgdata 0maxresident)k
  1212.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1213.     cmp cv-vars.good tmp2
  1214.     rm -f tmp tmp1 tmp2 tmp3 core junk spencer.tmp
  1215.     time ./sed -f 8to7.sed < 8bit.inp > tmp
  1216.     0.00user 0.01system 0:00.03elapsed 33%CPU (0avgtext+0avgdata 0maxresident)k
  1217.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1218.     cmp tmp 8to7.good
  1219.     tmp 8to7.good differ: char 1, line 1
  1220.     make: [8to7] Error 1 (ignored)
  1221.     time /usr/bin/sed -f 8to7.sed < 8bit.inp > tmp2
  1222.     0.01user 0.01system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1223.     0inputs+0outputs (0major+0minor)pagefaults 0swaps
  1224.     cmp tmp2 8to7.good
  1225.     tmp2 8to7.good differ: char 1, line 1
  1226.     make: [8to7] Error 1 (ignored)
  1227.     
  1228. one (known) failure for not having an obscure posix feature in sed.
  1229. everything else works.
  1230.  
  1231. perf very comperable with 2.05 on most of these (small) tests.
  1232.  
  1233. rxdispencer totally wins on the maddingcrowd; 2.05 uses vast memory
  1234. and takes "forever"
  1235.  
  1236. rxdispencer annoyingly 10x slower on mac-mf.  prbly acceptable for a release
  1237. but....
  1238.  
  1239.  
  1240.  
  1241. Fri Dec 29 13:54:34 PST 1995
  1242.  
  1243. looking at mac-mf
  1244.                  calls
  1245.   0.00     0.00     8.36     470  canonical_unfa
  1246.  
  1247. that suggests unfa caching is doing fine.
  1248.  
  1249.  
  1250.  
  1251.   0.00     0.00     8.36     847  rx_really_free_superstate
  1252.  
  1253. aha...  we are overrunning the superstate cache.
  1254.  
  1255. The top functions look suspicious:
  1256.  
  1257.       5.86     0.49     3.26   299341  malloc
  1258.       5.38     0.45     3.71    4376  rx_hash_store
  1259.       4.78     0.40     4.11   147917  eclose_node
  1260.  
  1261. once again ... that is a lot of calls to eclose_node
  1262.  
  1263.  
  1264.   3.35     0.28     5.08     865  rx_superstate
  1265.  
  1266. That is *really* weird.  Almost as many superstates
  1267. were really freed as were constructed.
  1268.  
  1269. br in exit and look at the "default_cache" and process size:
  1270.  
  1271.                   TSIZ DSIZ RSS
  1272.  9767 pp4 T     0:09     168  120 2608 1728    xx 11.6 /home/lord/vac/rxdispencer/sed/testsuite/sed -f mac-mf.sed
  1273.  
  1274.  
  1275.       lru_superstate = 0x18c000, 
  1276.       semifree_superstate = 0x0, 
  1277.       empty_superset = 0x79d80, 
  1278.       superstates = 239, 
  1279.       semifree_superstates = 0, 
  1280.       hits = 4, 
  1281.       misses = 135, 
  1282.       bytes_allowed = 1048576, 
  1283.       bytes_used = 1052192, 
  1284.  
  1285. the hit/miss ratio is consistant with overrunning the cache.
  1286. but why are there *no* semifree_superstates?
  1287.  
  1288.     br in semifree_superstate
  1289.     comm
  1290.     silent
  1291.     c
  1292.     end
  1293.  
  1294.  
  1295. hit 584 times
  1296.  
  1297. rx_really_free_superstate was (in a convoluted way) semifreeing
  1298. superstates at about the same rate they were being really freed.
  1299. unlikely to fix the perf. problem on mac-mf...but that is a bug
  1300. the solution is to semifree at twice the rate of really_free.
  1301.  
  1302. fix that and retry test.
  1303.  
  1304.     before:
  1305.  
  1306.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  1307.     8.22user 0.31system 0:15.97elapsed 53%CPU (0avgtext+0avgdata 0maxresident)k
  1308.  
  1309.  
  1310.     after:
  1311.  
  1312.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  1313.     8.37user 0.37system 0:10.84elapsed 80%CPU (0avgtext+0avgdata 0maxresident)k
  1314.  
  1315. and cache stats:
  1316.  
  1317.       superstates = 238, 
  1318.       semifree_superstates = 166, 
  1319.       hits = 5, 
  1320.       misses = 124, 
  1321.       bytes_allowed = 1048576, 
  1322.       bytes_used = 1047452, 
  1323.  
  1324. all of which is good news (except the hit/miss which still suggests
  1325. the cache is being over-run.)
  1326.  
  1327. re-compile with 4x superstate cache size
  1328.  
  1329.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  1330.     8.10user 0.60system 0:15.41elapsed 56%CPU (0avgtext+0avgdata 0maxresident)k
  1331.  
  1332. hardly any change
  1333.  
  1334. re-compile with 4x unfa cache size.  slow down!
  1335.  
  1336.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  1337.     8.16user 0.49system 0:10.63elapsed 81%CPU (0avgtext+0avgdata 0maxresident)k
  1338.  
  1339. odd cache data, too:
  1340.  
  1341.       superstates = 596, 
  1342.       semifree_superstates = 0, 
  1343.       hits = 17, 
  1344.       misses = 596, 
  1345.       bytes_allowed = 4194304, 
  1346.       bytes_used = 2608228, 
  1347.  
  1348. far from overflowing the superstate cache
  1349.  
  1350. p rx_basic_uv, the unfa cache:
  1351.  
  1352.       delay = 2048, 
  1353.       delayed = 100, 
  1354.  
  1355. so that isn't overflowing either.
  1356.  
  1357. exploring that structure more shows that the hash table is
  1358. totally screwed -- everything hashes into the 0 bucket.
  1359.  
  1360. out of 100 regexps to rexp_hash...got these results...not the 
  1361. greatest hash function.
  1362.  
  1363.     0
  1364.     1
  1365.     4
  1366.     5
  1367.     61032
  1368.     61033
  1369.     61036
  1370.     61037
  1371.  
  1372. use more fields:
  1373.  
  1374.     0
  1375.     2
  1376.     6
  1377.     60954
  1378.     4294906336
  1379.     4294967290
  1380.  
  1381. hmm.
  1382.  
  1383. cribbed some hashing clue from ouster on grounds that hashing
  1384. csets and rexp_nodes is almost like hashing strings.
  1385.  
  1386. much nicer:
  1387.  
  1388. 100 distinguishable calls to rexp_hash (distinct by addr of
  1389. rexp_node) giving 100 distinct hash values.  great.
  1390.  
  1391.  
  1392.     0        (struct rexp_node *) 0x0
  1393.     17006040        (struct rexp_node *) 0x74500
  1394.     19131804        (struct rexp_node *) 0x5e0c0
  1395.     21257568        (struct rexp_node *) 0x62e00
  1396.     21789009        (struct rexp_node *) 0x62c40
  1397.     22320450        (struct rexp_node *) 0x6b3c0
  1398.     24446214        (struct rexp_node *) 0x62a40
  1399.     24977655        (struct rexp_node *) 0x65cc0
  1400.     30823506        (struct rexp_node *) 0x5e7c0
  1401.     32417829        (struct rexp_node *) 0x65c80
  1402.     34543593        (struct rexp_node *) 0x70bc0
  1403.     35606475        (struct rexp_node *) 0x6e140
  1404.     35846082        (struct rexp_node *) 0x74300
  1405.     37200798        (struct rexp_node *) 0x70cc0
  1406.     37732239        (struct rexp_node *) 0x70b40
  1407.     40389444        (struct rexp_node *) 0x70c40
  1408.     44109531        (struct rexp_node *) 0x70ac0
  1409.     48892500        (struct rexp_node *) 0x6b640
  1410.     65367171        (struct rexp_node *) 0x6e0c0
  1411.     66430053        (struct rexp_node *) 0x70fc0
  1412.     86351200        (struct rexp_node *) 0x6b900
  1413.     110001468        (struct rexp_node *) 0x5eac0
  1414.     225255629        (struct rexp_node *) 0x6b480
  1415.     231371560        (struct rexp_node *) 0x70800
  1416.     312638818        (struct rexp_node *) 0x5ee00
  1417.     390934594        (struct rexp_node *) 0x70e40
  1418.     517283529        (struct rexp_node *) 0x746c0
  1419.     549067790        (struct rexp_node *) 0x1839c0
  1420.     572893326        (struct rexp_node *) 0x6b080
  1421.     601001026        (struct rexp_node *) 0x27f580
  1422.     606081253        (struct rexp_node *) 0x65dc0
  1423.     607263981        (struct rexp_node *) 0x69680
  1424.     621718215        (struct rexp_node *) 0x27f6c0
  1425.     650824273        (struct rexp_node *) 0x6ef40
  1426.     826472566        (struct rexp_node *) 0x6b2c0
  1427.     868635774        (struct rexp_node *) 0x65f00
  1428.     876091122        (struct rexp_node *) 0x206140
  1429.     888472439        (struct rexp_node *) 0x6e400
  1430.     929543565        (struct rexp_node *) 0x1e0b80
  1431.     931845394        (struct rexp_node *) 0x206180
  1432.     1058747076        (struct rexp_node *) 0x183900
  1433.     1207849365        (struct rexp_node *) 0x67880
  1434.     1278079982        (struct rexp_node *) 0x69f00
  1435.     1295802040        (struct rexp_node *) 0x27f480
  1436.     1310711465        (struct rexp_node *) 0x1e0b40
  1437.     1352930633        (struct rexp_node *) 0x76240
  1438.     1353620468        (struct rexp_node *) 0x27f700
  1439.     1356456513        (struct rexp_node *) 0x79ac0
  1440.     1379844369        (struct rexp_node *) 0x62400
  1441.     1402493327        (struct rexp_node *) 0x6bfc0
  1442.     1601102720        (struct rexp_node *) 0x5ef00
  1443.     1772669690        (struct rexp_node *) 0x183940
  1444.     1900599955        (struct rexp_node *) 0x27f440
  1445.     1968417710        (struct rexp_node *) 0xac140
  1446.     2108985499        (struct rexp_node *) 0x79b00
  1447.     2137694068        (struct rexp_node *) 0x651c0
  1448.     2204601669        (struct rexp_node *) 0x27f600
  1449.     2218807864        (struct rexp_node *) 0x799c0
  1450.     2223118861        (struct rexp_node *) 0x74780
  1451.     2236502798        (struct rexp_node *) 0x79840
  1452.     2278246773        (struct rexp_node *) 0x27f640
  1453.     2290967666        (struct rexp_node *) 0x73980
  1454.     2298725010        (struct rexp_node *) 0x1be500
  1455.     2303527273        (struct rexp_node *) 0xaca80
  1456.     2381124070        (struct rexp_node *) 0x27f680
  1457.     2418247494        (struct rexp_node *) 0x62200
  1458.     2437460954        (struct rexp_node *) 0xac000
  1459.     2439348845        (struct rexp_node *) 0x79140
  1460.     2455486158        (struct rexp_node *) 0x695c0
  1461.     2662071862        (struct rexp_node *) 0x183980
  1462.     2745345239        (struct rexp_node *) 0x74040
  1463.     2832160954        (struct rexp_node *) 0x70400
  1464.     2900057973        (struct rexp_node *) 0x76940
  1465.     2918628823        (struct rexp_node *) 0x79d00
  1466.     2956546377        (struct rexp_node *) 0x1e0b00
  1467.     3017127356        (struct rexp_node *) 0x27f400
  1468.     3031395249        (struct rexp_node *) 0xac1c0
  1469.     3111540809        (struct rexp_node *) 0xac180
  1470.     3225480365        (struct rexp_node *) 0x27f540
  1471.     3277401564        (struct rexp_node *) 0xe5b40
  1472.     3409840041        (struct rexp_node *) 0x27f740
  1473.     3441564462        (struct rexp_node *) 0x27f3c0
  1474.     3456946400        (struct rexp_node *) 0x65940
  1475.     3496700879        (struct rexp_node *) 0x27f4c0
  1476.     3531401660        (struct rexp_node *) 0x62cc0
  1477.     3546066190        (struct rexp_node *) 0x73f80
  1478.     3547538510        (struct rexp_node *) 0x790c0
  1479.     3548169742        (struct rexp_node *) 0x1e0d40
  1480.     3589031006        (struct rexp_node *) 0x79dc0
  1481.     3782143090        (struct rexp_node *) 0x79040
  1482.     3824014835        (struct rexp_node *) 0x693c0
  1483.     3837791013        (struct rexp_node *) 0x6ed80
  1484.     4036337975        (struct rexp_node *) 0x27f5c0
  1485.     4063573689        (struct rexp_node *) 0x5e580
  1486.     4107576897        (struct rexp_node *) 0x2061c0
  1487.     4140954487        (struct rexp_node *) 0x73080
  1488.     4168978309        (struct rexp_node *) 0x79b40
  1489.     4185396955        (struct rexp_node *) 0x27f500
  1490.     4200919815        (struct rexp_node *) 0x5e640
  1491.     4247337862        (struct rexp_node *) 0xaca00
  1492.     
  1493.  
  1494.  
  1495. but they still all go into the same damn bucket.
  1496.  
  1497. oops...H2B (hash->bucket) in rxhash.c was bogus do to a recent change away from %13.
  1498. fixed for 16 buckets --- still considering going back to %13
  1499.  
  1500. anyway...much better...here is rx_basic_uv...notice the spreading
  1501. of elements across all buckets in the hash table
  1502.  
  1503.     {
  1504.       delay = 2048, 
  1505.       delayed = 100, 
  1506.       table = {
  1507.         parent = 0x0, 
  1508.         refs = 16, 
  1509.         nested_p = 65535, 
  1510.         children = {0x59180, 0xb0c80, 0x8e380, 0x14dd80,
  1511.             0xd6380, 0x8e880, 0x59d00, 0x217d80,
  1512.             0x59900, 0x59600, 0xd6000, 0x1f8380,
  1513.             0xd6580, 0x59b80, 0x59e80, 0x59f00}
  1514.       }, 
  1515.       free_queue = 0x103960
  1516.     }
  1517.  
  1518. and overall time:
  1519.  
  1520.  
  1521.     before (-pg):
  1522.  
  1523.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  1524.     8.37user 0.37system 0:10.84elapsed 80%CPU (0avgtext+0avgdata 0maxresident)k
  1525.  
  1526.  
  1527.     after:
  1528.  
  1529.     6.94user 0.59system 0:13.71elapsed 54%CPU (0avgtext+0avgdata 0maxresident)k
  1530.  
  1531.  
  1532. Here is the superstate cache stats
  1533.  
  1534.       superstates = 596, 
  1535.       semifree_superstates = 0, 
  1536.       hits = 17, 
  1537.       misses = 596, 
  1538.       bytes_allowed = 4194304, 
  1539.       bytes_used = 2611648, 
  1540.  
  1541. this and the unfa cache make it clear that caching is not an issue now.
  1542.  
  1543. gprof says:
  1544.      33.33     2.50     2.50          mcount
  1545.       9.47     0.71     3.21   299018  malloc
  1546.       5.47     0.41     3.62     613  rx_superstate
  1547.       4.53     0.34     3.96   147465  eclose_node
  1548.       4.13     0.31     4.27   141219  rx_unfa
  1549.       3.73     0.28     4.55   280370  free
  1550.       3.33     0.25     4.80    5042  rx_regmatch
  1551.       3.20     0.24     5.04   141219  rx_free_unfa
  1552.       3.20     0.24     5.28   141219  rx_start_superstate
  1553.       2.13     0.16     5.44   145590  bzero
  1554.       2.13     0.16     5.60   141219  rx_make_solutions
  1555.       2.00     0.15     5.75   82154  rx_fit_p
  1556.       1.87     0.14     5.89   82154  rx_str_vmfn
  1557.       1.87     0.14     6.03    4039  rx_hash_store
  1558.       1.47     0.11     6.14   141444  rx_next_solution
  1559.       1.47     0.11     6.25   82154  rx_soluntion_fit_p
  1560.       1.33     0.10     6.35   146135  hash_se_prog
  1561.       1.33     0.10     6.45   143200  rx_free_solutions
  1562.       1.33     0.10     6.55    9006  rx_regexec
  1563.       1.20     0.09     6.64   142747  rx_state_possible_futures
  1564.       1.20     0.09     6.73   138315  rx_basic_make_solutions
  1565.     
  1566.  
  1567.  
  1568. Ripe for the picken'....
  1569.  
  1570. every one of these:
  1571.       2.13     0.16     5.60   141219  rx_make_solutions
  1572.  
  1573. which calls here:
  1574.  
  1575.       3.20     0.24     5.28   141219  rx_start_superstate
  1576.  
  1577. which calls here
  1578.  
  1579.     1.20     0.09     6.64   142747  rx_state_possible_futures
  1580.  
  1581. which calls here
  1582.  
  1583.       4.53     0.34     3.96   147465  eclose_node
  1584.  
  1585.  
  1586. the starting superstate should be better cached than that.
  1587. oops...this is another optimization not carried over from the
  1588. old rx.
  1589.  
  1590. looking further....grr!
  1591.  
  1592.     struct rx_possible_future *
  1593.     rx_state_possible_futures (rx, n)
  1594.          struct rx * rx;
  1595.          struct rx_nfa_state * n;
  1596.     #endif
  1597.     {
  1598.       if (n->futures_computed)
  1599.         return n->futures;
  1600.       else
  1601.         {
  1602.           struct eclose_frame frame;
  1603.           frame.prog_backwards = 0;
  1604.           if (!eclose_node (rx, n, n, &frame))
  1605.         return 0;
  1606.           else
  1607.         {
  1608.           struct rx_possible_future * p;
  1609.           return n->futures;
  1610.         }
  1611.         }
  1612.     }
  1613.     
  1614. that's the only occurence of "futures_computed" ...oops...
  1615. fixing that...
  1616.  
  1617.     before:
  1618.  
  1619.     6.94user 0.59system 0:13.71elapsed 54%CPU (0avgtext+0avgdata 0maxresident)k
  1620.  
  1621.     after:
  1622.  
  1623.     5.75user 0.32system 0:07.17elapsed 84%CPU (0avgtext+0avgdata 0maxresident)k
  1624.  
  1625.  
  1626. profiling
  1627.  
  1628.     % time  seconds   cumsec   calls  function
  1629.      34.00     2.05     2.05          mcount
  1630.       7.63     0.46     2.51   299018  malloc
  1631.       5.31     0.32     2.83   141219  rx_start_superstate
  1632.       4.64     0.28     3.11   280370  free
  1633.       4.48     0.27     3.38   141219  rx_unfa
  1634.       4.15     0.25     3.63   141219  rx_make_solutions
  1635.       3.81     0.23     3.86     613  rx_superstate
  1636.       3.65     0.22     4.08    5042  rx_regmatch
  1637.       3.48     0.21     4.29   141219  rx_free_unfa
  1638.       2.49     0.15     4.44   82154  rx_fit_p
  1639.       2.16     0.13     4.57   142747  rx_state_possible_futures
  1640.       1.82     0.11     4.68   145590  bzero
  1641.       1.82     0.11     4.79   138315  rx_basic_make_solutions
  1642.       1.82     0.11     4.90    9006  regnexec
  1643.       1.66     0.10     5.00   143200  rx_free_solutions
  1644.       1.49     0.09     5.09   130333  supersetcmp
  1645.       1.49     0.09     5.18   82154  rx_soluntion_fit_p
  1646.       1.49     0.09     5.27    4039  rx_hash_store
  1647.       1.33     0.08     5.35     745  __sbrk
  1648.       1.16     0.07     5.42   141444  rx_next_solution
  1649.       1.00     0.06     5.48   229493  rx_free_rexp
  1650.     
  1651.  
  1652. so good, eclose_node is off the map.
  1653.  
  1654.  
  1655. -O time:
  1656.  
  1657.     before (last known):
  1658.     time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  1659.     21.74user 0.16system 0:21.90elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1660.  
  1661.     after:
  1662.     2.34user 0.36system 0:02.72elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
  1663.  
  1664. but 2.05 is still:
  1665.  
  1666.     time /usr/bin/sed -f mac-mf.sed < mac-mf.inp > tmp2
  1667.     0.28user 0.11system 0:00.39elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1668.  
  1669.  
  1670. code reordering in rx_start_superstate should eliminate calls to rx_state_possible_futures
  1671.  
  1672. after (-O):
  1673.     2.28user 0.34system 0:02.64elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
  1674.  
  1675. hehe  -O2:
  1676.  
  1677.     2.32user 0.31system 0:02.64elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
  1678.  
  1679.  
  1680.  
  1681. Fri Dec 29 16:43:44 PST 1995
  1682.  
  1683. getting harder to speed up now.
  1684.  
  1685. one observation is that malloc is the heaviest function, and almost
  1686. all the calls there come from rx_basic_make_solutions and rx_make_solutions.
  1687.  
  1688. put in a (thread-losing) malloc/free buffer for the two spots where
  1689. malloc/free are called often.
  1690.  
  1691. -pg mac-mf before:
  1692.  
  1693.     5.75user 0.32system 0:07.17elapsed 84%CPU (0avgtext+0avgdata 0maxresident)k
  1694.  
  1695. after (!):
  1696.  
  1697.     3.98user 0.45system 0:04.74elapsed 93%CPU (0avgtext+0avgdata 0maxresident)k
  1698.  
  1699. (after profiling) inlined the common & fastest path through rx_start_superstate
  1700. into rx_make_solutions.
  1701.  
  1702. after:
  1703.     3.88user 0.41system 0:04.34elapsed 98%CPU (0avgtext+0avgdata 0maxresident)k
  1704.  
  1705. back that one out since it is a tiny win and maintainence headache.
  1706.  
  1707. -O
  1708.  
  1709. time ./sed -f enable.sed < enable.inp > tmp
  1710. 0.00user 0.03system 0:00.05elapsed 60%CPU (0avgtext+0avgdata 0maxresident)k
  1711. time /usr/bin/sed -f enable.sed < enable.inp > tmp2
  1712. 0.01user 0.02system 0:00.05elapsed 60%CPU (0avgtext+0avgdata 0maxresident)k
  1713.  
  1714.  
  1715.  
  1716. time ./sed -f sep.sed < sep.inp > tmp
  1717. 0.02user 0.03system 0:00.06elapsed 83%CPU (0avgtext+0avgdata 0maxresident)k
  1718. time /usr/bin/sed -f sep.sed < sep.inp > tmp2
  1719. 0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1720.  
  1721.  
  1722.  
  1723. time ./sed -f inclib.sed < inclib.inp > tmp
  1724. 0.00user 0.03system 0:00.05elapsed 60%CPU (0avgtext+0avgdata 0maxresident)k
  1725. time /usr/bin/sed -f inclib.sed < inclib.inp > tmp2
  1726. 0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1727.  
  1728.  
  1729.  
  1730. time ./sed -f 8bit.sed < 8bit.inp > tmp
  1731. 0.00user 0.02system 0:00.05elapsed 40%CPU (0avgtext+0avgdata 0maxresident)k
  1732. time /usr/bin/sed -f 8bit.sed < 8bit.inp > tmp2
  1733. 0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1734.  
  1735.  
  1736.  
  1737. time ./sed -f newjis.sed < newjis.inp > tmp
  1738. 0.01user 0.01system 0:00.04elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1739. time /usr/bin/sed -f newjis.sed < newjis.inp > tmp2
  1740. 0.01user 0.01system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  1741.  
  1742.  
  1743.  
  1744. time ./sed -n -f cv-vars.sed < cv-vars.inp > tmp
  1745. 0.01user 0.05system 0:00.08elapsed 75%CPU (0avgtext+0avgdata 0maxresident)k
  1746. time /usr/bin/sed -n -f cv-vars.sed < cv-vars.inp > tmp2
  1747. 0.01user 0.02system 0:00.04elapsed 75%CPU (0avgtext+0avgdata 0maxresident)k
  1748.  
  1749.  
  1750.  
  1751. time ./sed -f manis.sed < manis.inp > tmp
  1752. 0.07user 0.02system 0:00.09elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1753. time /usr/bin/sed -f manis.sed < manis.inp > tmp2
  1754. 0.02user 0.01system 0:00.04elapsed 75%CPU (0avgtext+0avgdata 0maxresident)k
  1755.  
  1756.  
  1757.  
  1758. time ./sed -f xabcx.sed < xabcx.inp > tmp
  1759. 0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1760. time /usr/bin/sed -f xabcx.sed < xabcx.inp > tmp2
  1761. 0.01user 0.03system 0:00.12elapsed 33%CPU (0avgtext+0avgdata 0maxresident)k
  1762.  
  1763.  
  1764.  
  1765. time ./sed -f dollar.sed < dollar.inp > tmp
  1766. 0.01user 0.02system 0:00.04elapsed 75%CPU (0avgtext+0avgdata 0maxresident)k
  1767. time /usr/bin/sed -f dollar.sed < dollar.inp > tmp2
  1768. 0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1769.  
  1770.  
  1771.  
  1772. time ./sed -f noeol.sed < noeol.inp > tmp
  1773. 0.01user 0.01system 0:00.04elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1774. time /usr/bin/sed -f noeol.sed < noeol.inp > tmp2
  1775. 0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1776.  
  1777.  
  1778.  
  1779. time ./sed -f sub-num.sed < sub-num.inp > tmp
  1780. 0.00user 0.03system 0:00.04elapsed 75%CPU (0avgtext+0avgdata 0maxresident)k
  1781. time /usr/bin/sed -f sub-num.sed < sub-num.inp > tmp2
  1782. 0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1783.  
  1784.  
  1785.  
  1786. time ./sed -f sub-all.sed < sub-num.inp > tmp
  1787. 0.01user 0.00system 0:00.03elapsed 33%CPU (0avgtext+0avgdata 0maxresident)k
  1788. time /usr/bin/sed -f sub-all.sed < sub-num.inp > tmp2
  1789. 0.01user 0.01system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  1790.  
  1791.  
  1792.  
  1793. time ./sed -f subwrite.sed < subwrite.inp > tmp1
  1794. 0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1795. time /usr/bin/sed -f subwrite.sed < subwrite.inp > tmp1
  1796. 0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1797.  
  1798.  
  1799.  
  1800. time ./sed -f head.sed < head.inp > tmp
  1801. 0.00user 0.01system 0:00.03elapsed 33%CPU (0avgtext+0avgdata 0maxresident)k
  1802. time /usr/bin/sed -f head.sed < head.inp > tmp2
  1803. 0.00user 0.01system 0:00.02elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1804.  
  1805.  
  1806.  
  1807. time ./sed -n -f middle.sed < head.inp > tmp
  1808. 0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1809. time /usr/bin/sed -n -f middle.sed < head.inp > tmp2
  1810. 0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1811.  
  1812.  
  1813.  
  1814. time ./sed -f maddingcrowd.sed < maddingcrowd.inp > tmp
  1815. 2.64user 0.70system 0:05.88elapsed 56%CPU (0avgtext+0avgdata 0maxresident)k
  1816. echo DO NOT time /usr/bin/sed -f maddingcrowd.sed < maddingcrowd.inp > tmp2
  1817. echo sed 2.05....  t->+inf
  1818.  
  1819.  
  1820.  
  1821. time ./sed -f mac-mf.sed < mac-mf.inp > tmp
  1822. 1.51user 0.30system 0:01.91elapsed 94%CPU (0avgtext+0avgdata 0maxresident)k
  1823. time /usr/bin/sed -f mac-mf.sed < mac-mf.inp > tmp2
  1824. 0.30user 0.10system 0:00.45elapsed 88%CPU (0avgtext+0avgdata 0maxresident)k
  1825.  
  1826.  
  1827.  
  1828. time ./sed -f khadafy.sed < khadafy.inp > tmp
  1829. 0.01user 0.01system 0:00.04elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1830. time /usr/bin/sed -f khadafy.sed < khadafy.inp > tmp2
  1831. 0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1832. sh spencer.sh ./sed <  spencer.inp > spencer.tmp 
  1833. sh spencer.tmp
  1834.  
  1835.  
  1836.  
  1837. time ./sed -f linecnt.sed < linecnt.inp > tmp
  1838. 0.00user 0.02system 0:00.04elapsed 50%CPU (0avgtext+0avgdata 0maxresident)k
  1839. time /usr/bin/sed -f linecnt.sed < linecnt.inp > tmp2
  1840. 0.00user 0.02system 0:00.02elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1841.  
  1842.  
  1843.  
  1844. time ./sed -f readin.sed < readin.inp >tmp
  1845. 0.02user 0.02system 0:00.05elapsed 80%CPU (0avgtext+0avgdata 0maxresident)k
  1846. time /usr/bin/sed -f readin.sed < readin.inp >tmp2
  1847. 0.01user 0.01system 0:00.06elapsed 33%CPU (0avgtext+0avgdata 0maxresident)k
  1848.  
  1849.  
  1850.  
  1851. time ./sed --file=newjis.sed < newjis.inp > tmp
  1852. 0.01user 0.01system 0:00.03elapsed 66%CPU (0avgtext+0avgdata 0maxresident)k
  1853. time /usr/bin/sed --file=newjis.sed < newjis.inp > tmp2
  1854. 0.00user 0.03system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1855.  
  1856.  
  1857.  
  1858. time ./sed --quiet -f cv-vars.sed < cv-vars.inp > tmp
  1859. 0.03user 0.02system 0:00.05elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1860. time /usr/bin/sed --quiet -f cv-vars.sed < cv-vars.inp > tmp2
  1861. 0.01user 0.02system 0:00.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
  1862.  
  1863.  
  1864.  
  1865.  
  1866.  
  1867.